Детектив в 1 части.
Эта история произошла в октябре.
Есть Ceph версии 0.94 (Hammer). 6 стораджей, 8 мониторов, по 6-8 osd на каждом сторадже, SSD диски объемом от 1 ТБ до 4 ТБ. Реплика — 2, минимум 1.
Как-то раз случилось такое: вечером прошел некий шторм по всему кластеру и самопроизвольно перезапустилось множество osd. В логах osd были видны стандартные для ceph ошибки вида no reply from osd.X. Немного slow requests и самопроизвольные рестарты, что для ceph не критическое событие и довольно частое. В общем, такое бывает. Но, к сожалению, не все перезапустившиеся osd смогли подняться. А именно пала героем osd.45 на storage6.
Мы решили, что это нестрашно, ведь это всего 1 из 50 osd, и пробовали запустить ее разными способами. Ну, знаете, umount/mount директории, flush и пересоздание журнала, вот это всё. В итоге, как обычно в таких ситуациях поступает любой админ, дело кончилось перезапуском всей ноды, так как из опыта известно, что systemd иногда немножко сходит с ума и не хочет корректно запускать нужные процессы. Или у osd перестает что-то работать, и без перезапуска сервера она не хочет запускаться.
И после перезапуска мы уже имели 4 мертвых osd, т.е. все на этом сторадже. Ошибки такие же, как и на первичной osd:
017-10-12 12:10:01.756562 7f02459af880 0 ceph version 0.94.10 (b1e0532418e4631af01acbc0cedd426f1905f4af), process ceph-osd, pid 2343
2017-10-12 12:10:01.767719 7f02459af880 0 filestore(/var/lib/ceph/osd/ceph-45) backend xfs (magic 0x58465342)
2017-10-12 12:10:01.769302 7f02459af880 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-45) detect_features: FIEMAP ioctl is supported and appears to work
2017-10-12 12:10:01.769310 7f02459af880 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-45) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
2017-10-12 12:10:01.785177 7f02459af880 0 genericfilestorebackend(/var/lib/ceph/osd/ceph-45) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
2017-10-12 12:10:01.785229 7f02459af880 0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-45) detect_feature: extsize is disabled by conf
2017-10-12 12:10:01.788289 7f02459af880 0 filestore(/var/lib/ceph/osd/ceph-45) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
2017-10-12 12:10:01.790182 7f02459af880 -1 journal FileJournal::_open: disabling aio for non-block journal. Use journal_force_aio to force use of aio anyway
2017-10-12 12:10:01.790184 7f02459af880 1 journal _open /var/lib/ceph/osd/ceph-45/journal fd 19: 10485760000 bytes, block size 4096 bytes, directio = 1, aio = 0
2017-10-12 12:10:01.790428 7f02459af880 1 journal _open /var/lib/ceph/osd/ceph-45/journal fd 19: 10485760000 bytes, block size 4096 bytes, directio = 1, aio = 0
2017-10-12 12:10:01.790923 7f02459af880 0 <cls> cls/hello/cls_hello.cc:271: loading cls_hello
2017-10-12 12:10:01.796251 7f02459af880 0 osd.45 19681 crush map has features 1107558400, adjusting msgr requires for clients
2017-10-12 12:10:01.796260 7f02459af880 0 osd.45 19681 crush map has features 1107558400 was 8705, adjusting msgr requires for mons
2017-10-12 12:10:01.796263 7f02459af880 0 osd.45 19681 crush map has features 1107558400, adjusting msgr requires for osds
2017-10-12 12:10:01.796273 7f02459af880 0 osd.45 19681 load_pgs
2017-10-12 12:10:01.850570 7f02459af880 -1 *** Caught signal (Aborted) **
in thread 7f02459af880
ceph version 0.94.10 (b1e0532418e4631af01acbc0cedd426f1905f4af)
1: /usr/bin/ceph-osd() [0xb35f7d]
2: (()+0x11390) [0x7f0244897390]
3: (gsignal()+0x38) [0x7f0242c8f428]
4: (abort()+0x16a) [0x7f0242c9102a]
5: (__gnu_cxx::__verbose_terminate_handler()+0x16d) [0x7f02435d284d]
6: (()+0x8d6b6) [0x7f02435d06b6]
7: (()+0x8d701) [0x7f02435d0701]
8: (()+0x8d919) [0x7f02435d0919]
9: (object_info_t::decode(ceph::buffer::list::iterator&)+0xb7a) [0x7b47ba]
10: (object_info_t::object_info_t(ceph::buffer::list&)+0x1b7) [0x78cd07]
11: (PGLog::read_log(ObjectStore*, coll_t, coll_t, ghobject_t, pg_info_t const&, std::map<eversion_t, hobject_t, std::less<eversion_t>, std::allocator<std::pair<eversion_t const, hobject_t> > >&, PGLog::IndexedLog&, pg_missing_t&, std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >&, std::set<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >*)+0xf52) [0x784c82]
12: (PG::read_state(ObjectStore*, ceph::buffer::list&)+0x24e) [0x81791e]
13: (OSD::load_pgs()+0xbb6) [0x6b9eb6]
14: (OSD::init()+0x137f) [0x6bdddf]
15: (main()+0x2c20) [0x646310]
16: (__libc_start_main()+0xf0) [0x7f0242c7a830]
17: (_start()+0x29) [0x65c779]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
Если стартовать osd напрямую через бинарь, а не через upstart или systemctl, то можно увидеть выбрасываемое исключение и немного побольше инфы (бинарь по дефолту пишет STDERR и STDOUT в консоль):
root@storage6:~# /usr/bin/ceph-osd -f --cluster ceph --id 45
starting osd.45 at :/0 osd_data /var/lib/ceph/osd/ceph-45 /var/lib/ceph/osd/ceph-45/journal
2017-10-12 15:13:45.288995 7fc5b1b06880 -1 osd.45 22551 log_to_monitors {default=true}
terminate called after throwing an instance of 'ceph::buffer::malformed_input'
what(): buffer::malformed_input: __PRETTY_FUNCTION__ decode past end of struct encoding
*** Caught signal (Aborted) **
in thread 7fc58e699700
terminate called recursively
Aborted (core dumped)Здесь мы видим, что демон ругается на какие-то неправильные входные данные (malformed_input). Но что это за данные, пока непонятно. Ситуация осложняется тем, что в кластере появились unfound объекты:
recovery 3/3102030 unfound (0.000%)Эти 4 незапускающиеся osd через таймаут были помечены мониторами как out. Началось восстановление и репликация данных, и в кластере появилось ни с того ни с сего 100 непроходящих slow requests. Так как Ceph используется Openstack'ом в качестве storage backend'а (не prod, но dev окружение) клиенты (команды разработки) это очень почувствовали и вся работа заметно замедлилась, так как виртуалки сильно тормозили.
В Ceph у нас два пула. Один для непосредственно дисков виртуалок — rbd1, второй — для образов, из которых создаются эти диски. Unfound объекты в данном случае критичны для обоих пулов, так как могут стать следствием неконсистентности данных. Но если в первом случае — все анфаунды в rbd1 — мы будем иметь максимум 3 фарша, то во втором случае — все анфаунды в images — мы потенциально имеем целый магазинчик фарша в связи с особенностями работы Openstack. Поэтому, так как мы в принципе были готовы потерять три машины, потому что опенстек — это не продакшн, требовалось проверить, к какому пулу относятся эти ненайденные объекты:
root@volume1:~# ceph pg 2.67 list_missing
{
"offset": {
"oid": "",
"key": "",
"snapid": 0,
"hash": 0,
"max": 0,
"pool": -1,
"namespace": ""
},
"num_missing": 3,
"num_unfound": 3,
"objects": [
{
"oid": {
"oid": "rbd_data.8e53d86b8b4567.0000000000000220",
"key": "",
"snapid": -2,
"hash": 2391933031,
"max": 0,
"pool": 2,
"namespace": ""
},
"need": "19232'24922826",
"have": "19172'24922749",
"locations": []
},
{
"oid": {
"oid": "rbd_data.42375f55c840f3.000000000000c6d3",
"key": "",
"snapid": -2,
"hash": 1598576743,
"max": 0,
"pool": 2,
"namespace": ""
},
"need": "19229'24922824",
"have": "19110'24922274",
"locations": []
},
{
"oid": {
"oid": "rbd_data.b4b7816b8b4567.0000000000000298",
"key": "",
"snapid": -2,
"hash": 2351466599,
"max": 0,
"pool": 2,
"namespace": ""
},
"need": "19229'24922823",
"have": "19110'24921517",
"locations": []
}
],
"more": 0
}Они все были на одной osd, в одной pg и в пуле номер 2. И… это пул rbd1, так что выдохнули. Если что, мы теряем всего три виртуалки, это не так страшно.
Удаляем одну из проблемных osd из кластера с помощью `ceph osd rm osd.45`. Анфаундов становится 28. Да что ж такое! Это уже проблема. Нужно любым способом попытаться восстановить неработающие osd, или нас ждет полный ресетап всех виртуалок в Openstack, а это, во-первых, сложно, а во-вторых, ужасно стыдно. В общем, мы врубили режим лютого дебага.
Итак, что у нас есть в данный момент?
— по кластеру прошла какая-то аномалия, заставившая часть osd перезапуститься;
— одна из них не смогла запуститься;
— после рестарта ее ноды не смогли запуститься оставшиеся osd;
— в кластере есть заблокированные запросы, все на одной osd (8ая);
— кластере есть unfound объекты (28 штук), все на той же самой osd (8ая);
— видимо, удаление из кластера остальных osd опять увеличит количество анфаундов, значит делать это не стоит;
— клиенты страдают, recovery периодически останавливается и приходится его триггерить перезапуском любой из работающих osd (кластер ceph иногда может залипать и переставать восстанавливаться. тогда нужно стриггерить восстановление событием: osd up->osd down->osd up).
Стрейсим запуск osd.45:
pidof `start ceph-osd id=45` | xargs strace -p 2> 45-strace.log
Видим, что osd спотыкается на чтении одного из участка локальных данных, после чего выбрасывается знакомое уже нам исключение ceph::buffer::malformed_input:
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head", {st_mode=S_IFDIR|0755, st_size=24576, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C", {st_mode=S_IFDIR|0755, st_size=24576, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0", {st_mode=S_IFDIR|0755, st_size=24576, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0", {st_mode=S_IFDIR|0755, st_size=24576, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D/DIR_B", 0x7ffcccfdf330) = -1 ENOENT (No such file or directory)
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D/rbd\udata.e1bde639901b63.0000000000000000__head_852BD00C__2", {st_mode=S_IFREG|0644, st_size=8388608, ...}) = 0
stat("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D/rbd\udata.e1bde639901b63.0000000000000000__head_852BD00C__2", {st_mode=S_IFREG|0644, st_size=8388608, ...}) = 0
open("/var/lib/ceph/osd/ceph-45/current/2.c_head/DIR_C/DIR_0/DIR_0/DIR_D/rbd\udata.e1bde639901b63.0000000000000000__head_852BD00C__2", O_RDWR) = 22
fgetxattr(22, "user.ceph._", 0x7ffcccfdf7c0, 100) = -1 ERANGE (Numerical result out of range)
fgetxattr(22, "user.ceph._", NULL, 0) = 250
fgetxattr(22, "user.ceph._", "1710r143I(rbd_data.e1bde639901b63.0000000000000000376377377377377377377377f320+205263342377377377377377377377377377377377377M311274234KL311274234K222510h361374341244v200265?336Y256270N52225M3112742", 250) = 250
futex(0x7f963ba19680, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(2, "terminate called after throwing "..., 48) = 48
write(2, "ceph::buffer::malformed_input", 29) = 29
write(2, "'n", 2) = 2
write(2, " what(): ", 11) = 11
write(2, "buffer::malformed_input: __PRETT"..., 79) = 79
write(2, "n", 1) = 1
rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
tgkill(23708, 23708, SIGABRT) = 0
--- SIGABRT {si_signo=SIGABRT, si_code=SI_TKILL, si_pid=23708, si_uid=0} ---
write(2, "*** Caught signal (Aborted) **n "..., 55) = 55
futex(0x7f963b802110, FUTEX_WAKE_PRIVATE, 2147483647) = 0
write(2, " ceph version 0.94.10 (b1e053241"..., 1418) = 1418
futex(0x48d40b4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x48d40b0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x48d4030, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x48d4058, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
Возможно, битый, неконсистентый объект e1bde639901b63.0000000000000000__head_852BD00C__2? Так как по стрейсу четко видно, что исключение выбрасывается после попытки обработать данный объект. Что ж, ищем его реплику на других стораджах:
find /mnt/osd? -name *e1bde639901b63.0000000000000000__head_852BD00C*Находим его на storage5 у osd.37. Сверяем md5-сумму. Одинаковая. Ну, может xattr`ы отличаются? Аккуратно копируем rsync'ом объект с storage5 на storage6 с сохранением всей мета-информации. Бэкапим оригинальный файл и заменяем его скопированным. Пробуем запустить, но безрезультатно — всё то же самое. Но ведь там osd работает! Как же так?
Углубляемся в изучение исходного кода демонов и ищем, из-за чего он может валиться. Тут на этом этапе нам уже помогает C++ разработчик Азат, который знал о ceph, но никогда с ним не работал.
Понятно, что проблема в данных, извлекаемых при boot-процессе osd. Пробуем запускать другие, здоровые osd и стрейсим их, чтобы понять, как же они должны по-нормальному работать. Запускаем заболевшие osd через gdb и пытаемся в дебаг. Сравниваем процесс запуска.
Через несколько часов разработчик говорит, что понимает, в чем разница старта osd, и на каком участке кода она валится, но непонятна первопричина такого поведения. Говорит, что 37ая osd (с которой мы скопировали «валидный» объект) тогда тоже не должна работать. Предлагает ее перезапустить, чтобы доказать гипотезу. Мы в отказ. Мол, и так все плохо, а там вообще другая нода, как бы хуже не было от этого. Разработчик же говорит логичную вещь, что это все равно не дело, что оно там работает на соплях и в любой момент может упасть и не подняться, а так мы хоть докажем теорию и продвинемся дальше. Согласны. Рестартуем — не поднимается. Разработчику — счастье, нам — траур, так как анфаундов стало больше, а количество slow requests увеличилось до 800. Но что поделать. Понятно, что если при 100 медленных запросов клиенты хоть как-то могли работать, то при 800 всё окончательно встает колом.
Теперь у нас есть потенциально два полных стораджа, osd на которых висят на волоске и оставшиеся 3 запущенных osd на storage5 перезапуска не выдержат.
Начинаем сравнивать файловые системы и структуры файлов на здоровых osd, так как видим разницу в старте. Находим, что дело как будто бы кроется в xattr'ах и работе с ними. Для уточнения стрейсим здоровую osd:
pidof `start ceph-osd id=8` | awk {'print $1'} | xargs strace -fe open,fsetxattr -p 2>8-osd-xattr.straceМного, конечно, не дает, но видим, что в нормальной и сломанной osd по-разному происходят запросы при запуске. Одни с префиксами, другие без. Разработчик начал смотреть вообще все места, где xattr генерились иили читались, и там было видно, что такие xattr и должны генериться, но почему-то при чтении была ошибка. Как раз этот момент, почему так, и был непонятен. А потом мы смотрим в git upstream и видим, что добавили это относительно недавно.
Вот этот патч, который должен помочь корректно пройти процесс запуска и чтения файловой системы. Разработчик предлагает обновить Ceph и попробовать запуститься на нем. И между делом он невзначай говорит скорее в шутку: "Слушайте, ребят, а вы случайно не ставили тут никогда 10-й ceph?" И смеется. И один админ отвечает: "Да, случайно ставили, потом паппет переустановил нужную версию". Секунда тишины. И все начинают ржать.
А дело было вот в чем: storage[56] наливались самыми последними, в момент их сетапа из отдельного окружения были некорректно указаны apt pins, из-за чего поставилась дефолтная версия Ceph из убунтовских реп. Паппет прикатил ее, накатил osd, запустил их, они начали работать. Спустя сутки админ заметил, что версия ceph неправильная, внес изменения, установил верную, перезапустил (!!!) osd (не переналивая) и ушел курить бамбук. Спустя две недели произошел непонятный катаклизм, описанный в самом начале, из-за чего произошло нечто, и одна osd не поднялась.
Разработчик еще в середине пути смотрел на файловые структуры и не понимал, почему они такие странные, и списывал на возможные коррапты данных. Оказалось, что ребята из Ceph в 10-й версии (Jewel) изменили способ хранения и представления xattr'ов. Дело в том, что они раньше хранили все значения xattr'ов inline, но это было неоптимально и имело ограничение по длине. Соответственно, в 10-й версии они изменили структуру хранения и стали хранить их блоками, разбив на несколько частей. Osd инициализировалась на 10-й версии и проработала так сутки, создав объекты «по-новому», потом ее даунгрейдили, и она так проработала еще 2 недели. Почему она запустилась после даунгрейда — непонятно. Возможно, никогда не доходила до этих данных. Но в нашем случае она натыкалась на эти xattr'ы и не могла их переварить, выбрасывая исключение malformed_input.
Мы, конечно же, тут же установили на storage[56] Jewel версии Ceph'а, и все osd как миленькие запустились. Анфаунды ушли, заблокированные запросы тоже исчезли. Ceph начал восстанавливаться. Мы уже были почти уверены, что потеряем весь опенстек. И вот как получилось затащить. Конечно, большое спасибо разработчику, он очень помог.
Такая вот история. Через пару часов после возникновения проблемы один админ сказал, что узнал исключение (mailformed input), выбрасываемое демоном, и пошел смотреть в код, а там всего (!) 23 места, где оно может быть выброшено. Я посмеялся и сказал, что это много и неправильный подход, так как мы все равно не будем пересобирать сeph. В тот момент для меня это было дико, а масштаб проблемы позволял спокойно копаться в ceph, пробуя различные варианты. Но когда в конце этого дня я понял, что лучшего выхода нет, это показалось мне неплохим шансом, который нужно было использовать.
И в итоге подход «а давайте смотреть в сырцы приложения, чтобы понимать, что происходит и что происходит не так» оказался очень эффективным, а я был не прав.
Автор: nikitashalnov
